joshtronic/igor

Watch

fix: move logwatch to a daily pass behind a recurrence bar #432

Merged

joshtronic merged 1 commit from fix/432-logwatch-daily-recurrence-gate into master

2026-07-27 15:49:11 +00:00

igor commented

2026-07-26 18:24:47 +00:00

Collaborator

What this PR does

Logwatch ran hourly and filed on a single occurrence. Across five verified tickets that produced one false positive (an operator pause), one duplicate carrying a wrong cause, one real symptom with a wrong cause, and two good ones. Each ticket, right or wrong, then cost a full build → review → rework cycle -- so a ~40% diagnosis hit rate at the top of the funnel was setting the work rate for the whole fleet.

The watching was never the problem. The filing bar was: looking costs one model call, filing commits the fleet to an agentic cycle, and both were triggered by the same threshold.

Daily pass, reading yesterday whole
Deterministic recurrence gate in front of the model
Reviewer reports the observation, not a cause

1. Daily, over the full 24h

An hour of context cannot distinguish a transient from a chronic -- at that resolution they are identical, which is exactly why every blip got chased. A day can count, and the count is that discriminator.

Note it reads the whole 24h, not one hour of it. The original daily pass read only 00:00-01:00 and left 23 hours unwatched; that blind spot is what drove the move to hourly, and re-introducing it would trade one failure mode for another.

2. A recurrence gate before the model call

Failure signatures are extracted, normalized (pids, shas, durations flattened so one condition is one signature) and counted. Only signatures recurring >= 3 times reach the model; a one-off drops to a greppable digest line. A standing red state needs no special rule -- it recurs by definition. On a clean day the pass now returns without any model call at all.

Two filters make the count mean anything:

Source. Only systemd[N]: and [agent] lines count as evidence. The Claude session's prose is streamed into this same journal and talks about failures constantly. Measured on a real day, without this filter 37 signatures matched and the only one to clear the bar was invoking claude for PR review (timeout Nm) -- routine narration -- while the two genuine exit-28s sat below it.
timed out, not a bare timeout. The harness logs its own configured limit on every tick, which would clear any bar by itself.

3. No more diagnoses

Findings used to carry a confident cause, and it was wrong often enough to steer fixes wrong: one ticket blamed a permission profile for what was a bin/ prefix on a command, and the obvious response to that cause would have been to widen a permission. A finding with no cause costs nothing when it is incomplete. A finding with a wrong cause costs a wrong fix.

Validation against the real journal

Run against the actual agent.service journal for 2026-07-25:

journal: 9564 lines, 1282733 bytes
gate runtime: 0.27s

meets the 3x bar (would FILE):   (nothing)

all matched signatures, incl. below bar:
  2  Failed to start agent.service - Agent -- one tick: ...
  2  agent.service: Main process exited, code=exited, status=N/n/a
  2  agent.service: Failed with result 'exit-code'.
  1  [agent] warning: fetch of joshtronic/joshtronic.com failed; ...
distinct transients suppressed: 7

The old pass filed three tickets that day. This gate files zero, and everything it sees is a genuine failure smell sitting correctly below the bar. All model prose is gone.

Performance

The first cut used per-line grep/sed, which on 9,500 lines meant ~30,000 subprocesses and over two minutes for a single unit -- it would have eaten the tick budget whole. Rewritten as stream pipelines: 0.27s.

The tail -c 60000 cap on the journal read is also gone. A byte cap would silently bias every count by discarding the early hours of the day.

Known cost, accepted deliberately

Recall. A real problem visible ONLY in model narration no longer files. Both of this week's examples are in that class: the red make lint baseline (#423) and the silently dropped follow-up (#430). Both were genuinely useful tickets.

I think that is still the right trade, and that those two want their own mechanism rather than a noisier logwatch -- CI gating lint, and a structured harness warning when a session reports it could not complete a requested side-effect. Both were already named in those tickets' own "fixed looks like" sections. Flagging it explicitly so the loss is a decision, not a surprise.

Test plan

bash bin/test-logwatch.sh passes -- 20 new assertions covering signature stability, the bar, the source filter, the timeout/timed out distinction, transient counting, and sample extraction
make test passes (25 suites)
make lint exits 0
shellcheck lib/logwatch.sh bin/tick.sh clean
Run end-to-end against the real 2026-07-25 journal (output above), including the timing measurement
Verified every bin/tick.sh hunk falls inside the logwatch block (2385-2729)

On the igor#432 references in the code comments: there is no issue #432 -- this PR took that number. The comments therefore point here, which is where the full rationale lives. No issue was filed on purpose: you asked me to close issues rather than open them, and this change came out of our conversation, not a ticket.

## What this PR does Logwatch ran **hourly and filed on a single occurrence**. Across five verified tickets that produced one false positive (an operator pause), one duplicate carrying a wrong cause, one real symptom with a wrong cause, and two good ones. Each ticket, right or wrong, then cost a full build → review → rework cycle -- so a ~40% diagnosis hit rate at the top of the funnel was setting the work rate for the whole fleet. The watching was never the problem. The **filing bar** was: looking costs one model call, filing commits the fleet to an agentic cycle, and both were triggered by the same threshold. - [x] Daily pass, reading **yesterday whole** - [x] Deterministic recurrence gate in front of the model - [x] Reviewer reports the observation, **not a cause** ### 1. Daily, over the full 24h An hour of context cannot distinguish a transient from a chronic -- at that resolution they are identical, which is exactly why every blip got chased. A day can **count**, and the count is that discriminator. Note it reads the whole 24h, not one hour of it. The *original* daily pass read only `00:00-01:00` and left 23 hours unwatched; that blind spot is what drove the move to hourly, and re-introducing it would trade one failure mode for another. ### 2. A recurrence gate before the model call Failure signatures are extracted, normalized (pids, shas, durations flattened so one condition is one signature) and counted. Only signatures recurring **>= 3 times** reach the model; a one-off drops to a greppable digest line. A standing red state needs no special rule -- it recurs by definition. On a clean day the pass now returns **without any model call at all**. Two filters make the count mean anything: - **Source.** Only `systemd[N]:` and `[agent]` lines count as evidence. The Claude session's prose is streamed into this same journal and talks about failures constantly. Measured on a real day, without this filter 37 signatures matched and the only one to clear the bar was `invoking claude for PR review (timeout Nm)` -- routine narration -- while the two genuine exit-28s sat below it. - **`timed out`, not a bare `timeout`.** The harness logs its own configured limit on every tick, which would clear any bar by itself. ### 3. No more diagnoses Findings used to carry a confident cause, and it was wrong often enough to steer fixes wrong: one ticket blamed a permission profile for what was a `bin/` prefix on a command, and the obvious response to that cause would have been to widen a permission. A finding with no cause costs nothing when it is incomplete. A finding with a wrong cause costs a wrong fix. ## Validation against the real journal Run against the actual `agent.service` journal for 2026-07-25: ``` journal: 9564 lines, 1282733 bytes gate runtime: 0.27s meets the 3x bar (would FILE): (nothing) all matched signatures, incl. below bar: 2 Failed to start agent.service - Agent -- one tick: ... 2 agent.service: Main process exited, code=exited, status=N/n/a 2 agent.service: Failed with result 'exit-code'. 1 [agent] warning: fetch of joshtronic/joshtronic.com failed; ... distinct transients suppressed: 7 ``` The old pass filed **three** tickets that day. This gate files **zero**, and everything it sees is a genuine failure smell sitting correctly below the bar. All model prose is gone. ## Performance The first cut used per-line `grep`/`sed`, which on 9,500 lines meant ~30,000 subprocesses and **over two minutes** for a single unit -- it would have eaten the tick budget whole. Rewritten as stream pipelines: **0.27s**. The `tail -c 60000` cap on the journal read is also gone. A byte cap would silently bias every count by discarding the early hours of the day. ## Known cost, accepted deliberately **Recall.** A real problem visible ONLY in model narration no longer files. Both of this week's examples are in that class: the red `make lint` baseline (#423) and the silently dropped follow-up (#430). Both were genuinely useful tickets. I think that is still the right trade, and that those two want their own mechanism rather than a noisier logwatch -- CI gating lint, and a structured harness warning when a session reports it could not complete a requested side-effect. Both were already named in those tickets' own "fixed looks like" sections. Flagging it explicitly so the loss is a decision, not a surprise. ## Test plan - [x] `bash bin/test-logwatch.sh` passes -- 20 new assertions covering signature stability, the bar, the source filter, the `timeout`/`timed out` distinction, transient counting, and sample extraction - [x] `make test` passes (25 suites) - [x] `make lint` exits 0 - [x] `shellcheck lib/logwatch.sh bin/tick.sh` clean - [x] Run end-to-end against the real 2026-07-25 journal (output above), including the timing measurement - [x] Verified every `bin/tick.sh` hunk falls inside the logwatch block (2385-2729) --- **On the `igor#432` references in the code comments:** there is no issue #432 -- this PR took that number. The comments therefore point here, which is where the full rationale lives. No issue was filed on purpose: you asked me to close issues rather than open them, and this change came out of our conversation, not a ticket.

igor added 1 commit

2026-07-26 18:24:47 +00:00

fix: move logwatch to a daily pass behind a recurrence bar

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

Details

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

Details

3465fff871

Logwatch ran hourly and filed on a SINGLE occurrence. Over five verified
tickets that produced one false positive (an operator pause), one
duplicate carrying a wrong cause, one real symptom with a wrong cause,
and two good ones -- and each ticket, right or wrong, then cost a full
build/review/rework cycle. A ~40% diagnosis hit rate at the top of the
funnel was setting the work rate for the whole fleet.

Three changes, all aimed at the filing bar rather than the watching:

1. Daily, reading YESTERDAY whole. An hour of context cannot tell a
   transient from a chronic -- they are identical at that resolution --
   which is why every blip got chased. A day can COUNT, and the count is
   exactly that discriminator. The full 24h is read, not one hour of it:
   the ORIGINAL daily pass read only 00:00-01:00 and left 23 hours
   unwatched, which is what drove the move to hourly to begin with.

2. A deterministic recurrence gate in front of the model. Failure
   signatures are extracted, normalized (pids, shas, durations flattened
   so one condition is one signature) and counted; only those recurring
   >= LOGWATCH_MIN_OCCURRENCES (3) reach the model. A one-off drops to a
   greppable digest line. A standing red state needs no separate rule --
   it recurs by definition. On a clean day the pass now returns without
   any model call at all.

   Two filters make the count mean something:
   - Source: only `systemd[N]:` and `[agent]` lines are evidence. The
     Claude session's PROSE is streamed into this same journal and talks
     about failures constantly. Measured on 2026-07-25, without this
     filter 37 signatures matched and the only one to clear the bar was
     `invoking claude for PR review (timeout Nm)` -- routine narration --
     while the two genuine exit-28s sat below it.
   - "timed out", not a bare "timeout": the harness logs its own
     configured limit every tick, which would clear any bar by itself.

3. The reviewer reports the observation, not a cause. Findings used to
   carry a confident diagnosis and it was wrong often enough to steer
   fixes wrong -- one ticket blamed a permission profile for what was a
   path prefix on a command, where the obvious response would have been
   to widen a permission. No cause costs nothing when incomplete; a wrong
   cause costs a wrong fix.

Performance: the gate is stream pipelines, not per-line subprocesses. A
real day is ~9,500 lines / 1.28MB; per-line greps took over two minutes
and would have eaten the tick budget. It now runs in 0.27s.

The `tail -c 60000` on the journal read is gone with it -- a byte cap
would silently bias every count by discarding the early hours.

Known cost, accepted deliberately: recall. A real problem visible ONLY
in model narration -- a red lint baseline, a session reporting it could
not do something -- no longer files. Both of this week's examples want
their own mechanism (CI gating lint; a structured harness warning on a
dropped side-effect), not a noisier logwatch.

Validated against the real 2026-07-25 journal: the old pass filed three
tickets that day; this gate files zero, and the only signatures it sees
are the genuine exit-28 pair at 2x each, correctly below the bar.

igor commented

2026-07-26 18:28:38 +00:00

Author

Collaborator

🤖 Review — `COMMENT` (automated)

CI for 3465fff8: success

Moves the logwatch pass from hourly/file-on-first-occurrence to daily with a deterministic recurrence gate in front of the model call. The change is coherent, in scope, and the checklist is honest — every checked box maps to real code in the diff (daily window in logwatch_window_day/logwatch_done_today, the gate in lib/logwatch.sh, the "no cause" rewrite of the system prompt). CI is green and the new tests are substantive, not decorative. I'm not blocking, but there are enough reservations that a human should glance at this rather than have me stamp it.

Findings

bin/tick.sh ~2436 — the function's contract comment is now wrong. The header still says "Returns 0 if a model call ran (the tick did real work), 1 if the unit was skipped." The new clean-day early return (if [ -z "$digest" ] && [ "$silence_finding" -eq 0 ]; then ... return 0) returns 0 having made no model call, which then increments reviewed and makes do_logwatch_tick report reviewed N service journal(s) and return "did work". Not a behavior regression (a clean hour also returned 0 before), but the comment now misdescribes the contract and the reviewed counter no longer means what it says. Fixed looks like: update the comment, or return a distinct code for "gated, no call".
bin/tick.sh ~2488 — the digest is unbounded, and the tail -c 60000 cap it replaced is gone. The while IFS=$'\t' read -r cnt sig loop emits one block per recurring signature with no cap on signature count, and calls logwatch_samples "$journal" "$sig" per signature — each call re-normalizes the entire day's journal (two seds + paste + awk over ~1.3 MB). On the measured good day that's ~4 signatures and irrelevant; on a genuinely bad day with dozens of distinct recurring signatures it's O(n) full-journal rescans and a model payload with no ceiling. Given the PR's own framing about the tick budget, a cap on signatures-per-digest (and/or a single normalization pass reused across logwatch_samples calls) seems worth having.
lib/logwatch.sh logwatch_samples — awk -v w="$want" interprets backslash escapes in the value. awk -v processes escape sequences, so a signature containing a backslash (a Windows-ish path, a literal \n in an error message) won't compare equal to $1 and the function silently returns nothing. The finding still files, just with an empty evidence fence. Safer: pass via an env var and ENVIRON["want"], or -v with the value pre-escaped.
bin/test-logwatch.sh — one assertion is vacuous. eq "and none of them register as transients either" "0" "$(logwatch_distinct_transients "$PROSE" 1)" — with min=1, $1+0 < m+0 is false for every signature, so n is never set and the function prints 0 for any input, filtered or not. This test passes even if the source filter is deleted. Re-run it at the default bar (or with min high enough that unfiltered prose would register) to make it mean something.
Undocumented recall loss: silence/tick-gap detection got materially weaker. The igor#420 silence finding now requires the unit to produce zero journal lines for a whole 24h (previously: zero for one hour). A unit that dies for 20 hours but logged once at 03:00 no longer trips it, and won't trip the recurrence gate either. The "Known cost, accepted deliberately" section covers the narration-only class (#423, #430) but not this one. Worth naming explicitly so it's a decision rather than a surprise, same as the others.
logwatch_samples normalizes the full journal, not the source-filtered subset (lib/logwatch.sh). Signatures are derived only from systemd[N]:/[agent] lines, but evidence samples are matched across everything — so a Claude prose line that happens to normalize identically can be quoted as evidence for a systemd failure. Low impact, but it partially undoes the source filter at the point where the human actually reads the output.

Notes, non-blocking

Diff is ~420 added lines, modestly over the ~400 budget, but nothing was trimmed to fit and the split (lib helpers / tick wiring / tests / doc) is cohesive. I'd have accepted a stack here, but I'm not going to make you redo it for that.
Description says "20 new assertions"; I count ~23. Harmless.
The igor#432 references in code comments point at this PR, not an issue — disclosed in the description, and the rationale does live here. Flagging only so the human isn't surprised when the reference resolves to a PR.
Ordering in _logwatch_smell_signatures is right: grep SOURCE runs before normalization, so the systemd[N]: provenance marker isn't stripped out from under the filter. Good. Note the signature itself drops provenance, so identical message text from two sources would merge — probably fine, worth knowing.
Prompt nit: in the silence_finding path the digest placeholder is emitted under a header asserting "Each block below recurred at least 3x", which is false for that case. The placeholder text explains itself, so it likely reads fine, but it's a small contradiction in the prompt.

_{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 `3465fff8`: **success** Moves the logwatch pass from hourly/file-on-first-occurrence to daily with a deterministic recurrence gate in front of the model call. The change is coherent, in scope, and the checklist is honest — every checked box maps to real code in the diff (daily window in `logwatch_window_day`/`logwatch_done_today`, the gate in `lib/logwatch.sh`, the "no cause" rewrite of the system prompt). CI is green and the new tests are substantive, not decorative. I'm not blocking, but there are enough reservations that a human should glance at this rather than have me stamp it. ## Findings - **`bin/tick.sh` ~2436 — the function's contract comment is now wrong.** The header still says *"Returns 0 if a model call ran (the tick did real work), 1 if the unit was skipped."* The new clean-day early return (`if [ -z "$digest" ] && [ "$silence_finding" -eq 0 ]; then ... return 0`) returns 0 having made **no** model call, which then increments `reviewed` and makes `do_logwatch_tick` report `reviewed N service journal(s)` and return "did work". Not a behavior regression (a clean hour also returned 0 before), but the comment now misdescribes the contract and the `reviewed` counter no longer means what it says. Fixed looks like: update the comment, or return a distinct code for "gated, no call". - **`bin/tick.sh` ~2488 — the digest is unbounded, and the `tail -c 60000` cap it replaced is gone.** The `while IFS=$'\t' read -r cnt sig` loop emits one block per recurring signature with no cap on signature count, and calls `logwatch_samples "$journal" "$sig"` per signature — each call re-normalizes the *entire* day's journal (two `sed`s + `paste` + `awk` over ~1.3 MB). On the measured good day that's ~4 signatures and irrelevant; on a genuinely bad day with dozens of distinct recurring signatures it's O(n) full-journal rescans and a model payload with no ceiling. Given the PR's own framing about the tick budget, a cap on signatures-per-digest (and/or a single normalization pass reused across `logwatch_samples` calls) seems worth having. - **`lib/logwatch.sh` `logwatch_samples` — `awk -v w="$want"` interprets backslash escapes in the value.** `awk -v` processes escape sequences, so a signature containing a backslash (a Windows-ish path, a literal `\n` in an error message) won't compare equal to `$1` and the function silently returns nothing. The finding still files, just with an empty evidence fence. Safer: pass via an env var and `ENVIRON["want"]`, or `-v` with the value pre-escaped. - **`bin/test-logwatch.sh` — one assertion is vacuous.** `eq "and none of them register as transients either" "0" "$(logwatch_distinct_transients "$PROSE" 1)"` — with `min=1`, `$1+0 < m+0` is false for every signature, so `n` is never set and the function prints `0` for *any* input, filtered or not. This test passes even if the source filter is deleted. Re-run it at the default bar (or with `min` high enough that unfiltered prose would register) to make it mean something. - **Undocumented recall loss: silence/tick-gap detection got materially weaker.** The igor#420 silence finding now requires the unit to produce *zero* journal lines for a whole 24h (previously: zero for one hour). A unit that dies for 20 hours but logged once at 03:00 no longer trips it, and won't trip the recurrence gate either. The "Known cost, accepted deliberately" section covers the narration-only class (#423, #430) but not this one. Worth naming explicitly so it's a decision rather than a surprise, same as the others. - **`logwatch_samples` normalizes the full journal, not the source-filtered subset** (`lib/logwatch.sh`). Signatures are derived only from `systemd[N]:`/`[agent]` lines, but evidence samples are matched across everything — so a Claude prose line that happens to normalize identically can be quoted as evidence for a systemd failure. Low impact, but it partially undoes the source filter at the point where the human actually reads the output. ## Notes, non-blocking - Diff is ~420 added lines, modestly over the ~400 budget, but nothing was trimmed to fit and the split (lib helpers / tick wiring / tests / doc) is cohesive. I'd have accepted a stack here, but I'm not going to make you redo it for that. - Description says "20 new assertions"; I count ~23. Harmless. - The `igor#432` references in code comments point at this PR, not an issue — disclosed in the description, and the rationale does live here. Flagging only so the human isn't surprised when the reference resolves to a PR. - Ordering in `_logwatch_smell_signatures` is right: `grep SOURCE` runs *before* normalization, so the `systemd[N]:` provenance marker isn't stripped out from under the filter. Good. Note the signature itself drops provenance, so identical message text from two sources would merge — probably fine, worth knowing. - Prompt nit: in the `silence_finding` path the digest placeholder is emitted under a header asserting "Each block below recurred at least 3x", which is false for that case. The placeholder text explains itself, so it likely reads fine, but it's a small contradiction in the prompt. --- <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-26 18:28:39 +00:00

3 minutes 3 seconds

igor requested review from joshtronic

2026-07-26 18:28:39 +00:00