joshtronic/igor

Watch

fix: check `agent.timer` before filing a logwatch tick-gap finding #421

Merged

joshtronic merged 2 commits from agent/420-logwatch-files-false-tick-gap-tickets-when-the into master

2026-07-26 01:49:40 +00:00

igor commented

2026-07-25 03:32:28 +00:00

Collaborator

What this PR does

fix: check agent.timer before filing a logwatch tick-gap finding
Add logwatch_timer_transitioned (lib/logwatch.sh) -- true when a companion *.timer unit's own journal shows a Stopped/Started transition in the reviewed window (systemd only logs these on an actual state change, never on ordinary per-minute firing)
Wire it into logwatch_review_unit/do_logwatch_tick (bin/tick.sh): a unit's companion timer is discovered from the same systemd/ directory listing already used for .service discovery
- a transition in the window explains the silence -> skip / tell the reviewer not to file a tick-gap finding for it
- no transition + an empty service journal -> the timer was continuously active but the unit produced nothing -> now surfaced to the reviewer as a "Timer status" note instead of silently skipped, since that's itself a hard failure for a per-minute unit
- no transition + a normal, non-empty journal -> unaffected (nothing to explain)
Unit tests for logwatch_timer_transitioned covering all three scenarios from the issue plus two regex-precision checks (Starting/Stopping don't count; a transition line for a different unit doesn't count)
Document the new timer-aware behavior in CLAUDE.md's logwatch section

Test plan

make test passes (includes the new bin/test-logwatch.sh cases)
make lint -- no new shellcheck warnings introduced (2 pre-existing warnings in unrelated files/lines remain)
bash -n on all three touched shell files
No manual verification needed beyond the above; the actual journalctl/model-call path can't be exercised outside a live host, which is why the fix is covered at the pure-function level (logwatch_timer_transitioned) per the existing test style in bin/test-logwatch.sh

Closes #420

## What this PR does - [x] fix: check `agent.timer` before filing a logwatch tick-gap finding - [x] Add `logwatch_timer_transitioned` (`lib/logwatch.sh`) -- true when a companion `*.timer` unit's own journal shows a Stopped/Started transition in the reviewed window (systemd only logs these on an actual state change, never on ordinary per-minute firing) - [x] Wire it into `logwatch_review_unit`/`do_logwatch_tick` (`bin/tick.sh`): a unit's companion timer is discovered from the same `systemd/` directory listing already used for `.service` discovery - a transition in the window explains the silence -> skip / tell the reviewer not to file a tick-gap finding for it - no transition + an empty service journal -> the timer was continuously active but the unit produced nothing -> now surfaced to the reviewer as a "Timer status" note instead of silently skipped, since that's itself a hard failure for a per-minute unit - no transition + a normal, non-empty journal -> unaffected (nothing to explain) - [x] Unit tests for `logwatch_timer_transitioned` covering all three scenarios from the issue plus two regex-precision checks (`Starting`/`Stopping` don't count; a transition line for a different unit doesn't count) - [x] Document the new timer-aware behavior in `CLAUDE.md`'s logwatch section ## Test plan - [x] `make test` passes (includes the new `bin/test-logwatch.sh` cases) - [x] `make lint` -- no new shellcheck warnings introduced (2 pre-existing warnings in unrelated files/lines remain) - [x] `bash -n` on all three touched shell files - [x] No manual verification needed beyond the above; the actual `journalctl`/model-call path can't be exercised outside a live host, which is why the fix is covered at the pure-function level (`logwatch_timer_transitioned`) per the existing test style in `bin/test-logwatch.sh` Closes #420

igor added 1 commit

2026-07-25 03:32:28 +00:00

fix: check agent.timer before filing a logwatch tick-gap finding

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

Details

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

Details

2a6462bfdb

igor commented

2026-07-25 03:36:23 +00:00

Author

Collaborator

🤖 Review — `REQUEST_CHANGES` (automated)

CI for 2a6462bf: success

Adds logwatch_timer_transitioned and wires a companion-*.timer check into logwatch_review_unit/do_logwatch_tick so an operator pause explains a silent journal. The pure function is fine; the wiring introduces a new false-positive filing path that I think is a regression, plus a cadence assumption that doesn't hold for every discovered repo.

Blocking

1. A pause longer than one hour now files a finding that asserts the opposite of the truth (bin/tick.sh ~2450-2470).
The timer journal is fetched with the same --since win_start --until win_end window as the service journal. So a systemctl stop agent.timer at 10:30 that lasts until 14:00 produces:

window 10:00-11:00 → transition present → skip (correct, this is the #420 case)
windows 11:00-12:00, 12:00-13:00, 13:00-14:00 → no transition in the window, empty service journal → the new branch fires and feeds the reviewer "${timer_unit} was continuously active this window (no Stopped/Started transition observed) ... This silence is NOT explained by the timer and is itself failure-worthy."

The timer was stopped the whole time. Before this PR those hours were silently skipped; now they file a ticket whose body is factually wrong. The fix for #420 makes the >1h version of #420 worse. "No transition inside this hour" is not evidence of "continuously active" — it's evidence of "no state change in this hour", which is equally consistent with continuously stopped.

Fixed looks like: consult the timer's current state rather than inferring it (systemctl --user show -p ActiveState --value "$timer_unit", or is-active), and/or widen the timer journal lookback past win_start and use the last transition seen. Skip when the last known state is stopped.

2. Companion .timer is treated as "per-minute cadence" without reading the timer (bin/tick.sh do_logwatch_tick, prompt text ~2535).
Discovery walks every bot-accessible repo that declares systemd units. Any repo with a daily/weekly/OnCalendar timer + service pair now hits the empty-journal branch for ~23 of 24 hourly passes, each time telling the reviewer "for a timer-driven unit that silence is itself the failure". Nothing in the code reads OnCalendar/OnUnitActiveSec/OnBootSec to establish that the unit is actually expected to fire within the hour. Dedup limits the spam but doesn't make the first ticket correct. Either gate the new branch on an actual sub-hourly cadence parsed from the timer file, or restrict it to units whose cadence you can verify.

3. Verify set -e behavior on the un-guarded command substitution (bin/tick.sh, discovery loop).
Old: units=$(forgejo_repo_list_dir ... | grep ... || true) — the || true swallowed a failing lookup.
New: dir_listing=$(forgejo_repo_list_dir "$r_name" "systemd" 2>/dev/null) with no || true. Repos without a systemd/ dir are the common case, and if forgejo_repo_list_dir returns nonzero there, this assignment now carries a nonzero status. If tick.sh runs under set -e/errexit, that aborts the whole logwatch tick on the first non-systemd repo instead of continue-ing. I can't see the script's set line from the diff — please confirm, and add || true regardless since it costs nothing.

Non-blocking

Test coverage doesn't reach the changed logic. All four new assertions exercise logwatch_timer_transitioned, which is the trivial part; none exercise the new branching in logwatch_review_unit (transitioned + empty → skip/return 1; not-transitioned + empty → synthetic journal + timer_note + return 0; transitioned + non-empty → note), nor the base/timer_unit pairing in discovery. That branching is where both bugs above live.
Checklist wording overstates the tests. "covering all three scenarios from the issue plus two regex-precision checks" reads as 5 assertions; there are 4, and the third scenario ("no transition + non-empty journal") is a code comment, not an assertion — the function can't distinguish it, since it only sees the timer journal. Minor, but the checklist is what the human trusts.
logwatch_timer_transitioned's regex matches any *.timer, not the specific unit; harmless today because the journal is -u "$timer_unit"-scoped, but the test labelled "a Started/Stopped line for a DIFFERENT unit does not count" actually only proves that a non-timer line doesn't count. Consider passing the unit name in if you want that guarantee.
${timer_section} interpolates with leading blank lines even when empty → a couple of stray newlines in the prompt. Cosmetic.

Clean

Scope is tight (~120 lines, one issue), CI is green, no CI-config or security surface touched, CLAUDE.md genuinely documents the new behavior as claimed, and the "Do NOT file / DO file" prompt additions are consistent with the section ordering.

_{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 — `REQUEST_CHANGES` _(automated)_ CI for `2a6462bf`: **success** Adds `logwatch_timer_transitioned` and wires a companion-`*.timer` check into `logwatch_review_unit`/`do_logwatch_tick` so an operator pause explains a silent journal. The pure function is fine; the wiring introduces a new *false-positive filing* path that I think is a regression, plus a cadence assumption that doesn't hold for every discovered repo. ## Blocking **1. A pause longer than one hour now files a finding that asserts the opposite of the truth (`bin/tick.sh` ~2450-2470).** The timer journal is fetched with the *same* `--since win_start --until win_end` window as the service journal. So a `systemctl stop agent.timer` at 10:30 that lasts until 14:00 produces: - window 10:00-11:00 → transition present → skip (correct, this is the #420 case) - windows 11:00-12:00, 12:00-13:00, 13:00-14:00 → **no** transition in the window, empty service journal → the new branch fires and feeds the reviewer `"${timer_unit} was continuously active this window (no Stopped/Started transition observed) ... This silence is NOT explained by the timer and is itself failure-worthy."` The timer was stopped the whole time. Before this PR those hours were silently skipped; now they file a ticket whose body is factually wrong. The fix for #420 makes the >1h version of #420 worse. "No transition inside this hour" is not evidence of "continuously active" — it's evidence of "no state change *in this hour*", which is equally consistent with continuously stopped. Fixed looks like: consult the timer's *current* state rather than inferring it (`systemctl --user show -p ActiveState --value "$timer_unit"`, or `is-active`), and/or widen the timer journal lookback past `win_start` and use the **last** transition seen. Skip when the last known state is stopped. **2. Companion `.timer` is treated as "per-minute cadence" without reading the timer (`bin/tick.sh` `do_logwatch_tick`, prompt text ~2535).** Discovery walks *every* bot-accessible repo that declares systemd units. Any repo with a daily/weekly/`OnCalendar` timer + service pair now hits the empty-journal branch for ~23 of 24 hourly passes, each time telling the reviewer "for a timer-driven unit that silence is itself the failure". Nothing in the code reads `OnCalendar`/`OnUnitActiveSec`/`OnBootSec` to establish that the unit is actually expected to fire within the hour. Dedup limits the spam but doesn't make the first ticket correct. Either gate the new branch on an actual sub-hourly cadence parsed from the timer file, or restrict it to units whose cadence you can verify. **3. Verify `set -e` behavior on the un-guarded command substitution (`bin/tick.sh`, discovery loop).** Old: `units=$(forgejo_repo_list_dir ... | grep ... || true)` — the `|| true` swallowed a failing lookup. New: `dir_listing=$(forgejo_repo_list_dir "$r_name" "systemd" 2>/dev/null)` with no `|| true`. Repos *without* a `systemd/` dir are the common case, and if `forgejo_repo_list_dir` returns nonzero there, this assignment now carries a nonzero status. If `tick.sh` runs under `set -e`/`errexit`, that aborts the whole logwatch tick on the first non-systemd repo instead of `continue`-ing. I can't see the script's `set` line from the diff — please confirm, and add `|| true` regardless since it costs nothing. ## Non-blocking - **Test coverage doesn't reach the changed logic.** All four new assertions exercise `logwatch_timer_transitioned`, which is the trivial part; none exercise the new branching in `logwatch_review_unit` (transitioned + empty → skip/return 1; not-transitioned + empty → synthetic journal + `timer_note` + return 0; transitioned + non-empty → note), nor the `base`/`timer_unit` pairing in discovery. That branching is where both bugs above live. - **Checklist wording overstates the tests.** "covering all three scenarios from the issue plus two regex-precision checks" reads as 5 assertions; there are 4, and the third scenario ("no transition + non-empty journal") is a code comment, not an assertion — the function can't distinguish it, since it only sees the timer journal. Minor, but the checklist is what the human trusts. - `logwatch_timer_transitioned`'s regex matches any `*.timer`, not the specific unit; harmless today because the journal is `-u "$timer_unit"`-scoped, but the test labelled "a Started/Stopped line for a DIFFERENT unit does not count" actually only proves that a *non-timer* line doesn't count. Consider passing the unit name in if you want that guarantee. - `${timer_section}` interpolates with leading blank lines even when empty → a couple of stray newlines in the prompt. Cosmetic. ## Clean - Scope is tight (~120 lines, one issue), CI is green, no CI-config or security surface touched, `CLAUDE.md` genuinely documents the new behavior as claimed, and the "Do NOT file / DO file" prompt additions are consistent with the section ordering. --- <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-25 03:36:24 +00:00

1 minute 31 seconds

igor self-assigned this

2026-07-25 03:36:24 +00:00

igor commented

2026-07-25 03:51:10 +00:00

Author

Collaborator

🔧 Rework — round 1 (automated)

Addressed the review on claude-opus-5 at effort high — 1 new commit(s).

### 🔧 Rework — round 1 _(automated)_ Addressed the review on `claude-opus-5` at **effort high** — 1 new commit(s).

igor removed their assignment

2026-07-25 03:51:39 +00:00

igor referenced this pull request from a commit

2026-07-25 03:51:40 +00:00

fix: judge the timer's actual state, not just an in-window transition

igor added 1 commit

2026-07-25 03:51:40 +00:00

fix: judge the timer's actual state, not just an in-window transition

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

Details

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

Details

367e3feefb

Review feedback on #421.

1. A pause longer than the reviewed hour filed a finding asserting the
   opposite of the truth. `systemctl stop agent.timer` at 10:30 through
   14:00 logs a transition only in the 10:00-11:00 window; the 11:00,
   12:00 and 13:00 passes saw no transition, called the timer
   "continuously active" and ticketed the silence -- once per hour.
   logwatch_timer_verdict now folds in two more signals: the last
   transition in the LOGWATCH_TIMER_LOOKBACK_HOURS before the window,
   and `systemctl is-active` right now. It reports paused / active /
   unknown, and only `active` (positive evidence of continuous
   activity) lets an empty journal become a finding. The window read
   also runs to now, not win_end, so a transition between the window
   closing and the review still counts.

2. A companion .timer no longer implies per-minute cadence.
   logwatch_timer_subhourly parses the timer file (fetched from the
   same repo the .service was discovered in) for
   OnUnitActiveSec/OnUnitInactiveSec <= 1h or an OnCalendar whose hour
   field covers every hour. A daily timer, unparseable content, or an
   unreadable file all answer "no" -- silence stays a skip.

3. `|| true` on the systemd/ dir listing. Confirmed the errexit
   question: tick.sh runs `set -euo pipefail`, but the sole call site
   is `if do_logwatch_tick; then`, which suppresses errexit inside the
   function -- so it was not live. Guard added anyway; it costs
   nothing and survives that call site changing.

Also from the review: logwatch_timer_transitioned takes the unit name
so the regex is unit-specific, and the timer section no longer leaves
stray blank lines in the prompt.

Tests now cover the decision, not just the trivial part: verdict across
all five evidence combinations, cadence parsing for eight schedules,
and the lookback expression -- `date -d "$stamp -24 hours"` parses the
-24 as a UTC offset and walks FORWARD, which is exactly how the fix in
(1) would have silently reverted. It's a lib function now, and tested.

igor added spent time

2026-07-25 03:51:40 +00:00

12 minutes 35 seconds

igor commented

2026-07-25 03:56:29 +00:00

Author

Collaborator

🤖 Review — `COMMENT` (automated)

CI for 367e3fee: success

Adds timer-awareness to the hourly logwatch pass so a paused *.timer explains a silent service journal instead of producing a phantom tick-gap ticket (igor#420). Core logic reads sound and errs conservative (unknown/paused ⇒ skip), CI is green, scope is on-issue, size is within budget. Three things I want a human to weigh before merge — none of them break the #420 fix itself.

1. logwatch_timer_subhourly accepts exactly 3600s — that can re-create the false ticket this PR exists to kill (lib/logwatch.sh, secs -le 3600)
OnUnitActiveSec=/OnUnitInactiveSec= are measured from the paired service's activation/deactivation, not from a wall clock, so an "hourly" timer's effective period is 3600 + service runtime + up to AccuracySec (default 60s) of deferral. Firings drift later, and eventually a clock hour contains zero firings — at which point the new branch turns an empty journal into a "Timer status: silence is itself failure-worthy" prompt and files. OnCalendar=hourly (fixed :00:00) is safe; the monotonic forms are not. Suggested fix: -lt 3600 (or a margin like -le 1800) for the OnUnit*Sec branch only, and flip the "OnUnitActiveSec=1h -> exactly hourly, still counts" assertion in bin/test-logwatch.sh.

2. The new finding path depends on forgejo_repo_get_file, which isn't visible anywhere in this diff (bin/tick.sh ~2710)
timer_file=$(forgejo_repo_get_file "$r_name" "systemd/${base}.timer" 2>/dev/null || true) — I can't confirm from the diff that (a) the helper exists and (b) it returns decoded file contents rather than the Forgejo contents-API base64 blob. Either failure is masked by || true and silently yields timer_subhourly=0 forever, making the entire "active timer + silent unit ⇒ file" branch dead code with no test or log to reveal it. Please confirm the helper's contract (an existing call site would satisfy me); if it can return base64, decode it.

3. PR description no longer matches the diff
The checklist describes a two-state design built on logwatch_timer_transitioned. The diff actually ships five new functions — logwatch_timer_last_transition, logwatch_timer_verdict, logwatch_timer_lookback_since, logwatch_timespan_secs, logwatch_calendar_hourly, logwatch_timer_subhourly — including a general systemd timespan and OnCalendar parser, and the "empty journal ⇒ Timer status note" bullet is now additionally gated on is-active and declared cadence. Nothing checked is fabricated (every box maps to real code), but the description under-describes the change; a human trusting the checklist would not know a calendar-expression parser is in here. Worth updating so the CLAUDE.md text and the description agree.

Smaller notes, non-blocking:

Started|Stopped <unit> matching assumes systemd ≥ v250, which logs the unit ID; older systemd logs the Description instead, so the in-window signal would silently never fire there. The prior/is-active signals still cover it, so this degrades safely — just noting the test fixtures only cover the new format.
logwatch_timer_subhourly treats every OnCalendar=/OnUnit*Sec= line as additive; systemd resets the list on an empty assignment (OnCalendar=), so OnCalendar=hourly + OnCalendar= + OnCalendar=daily would be judged sub-hourly. Obscure, but it's the one direction that produces a false ticket.
LOGWATCH_TIMER_LOOKBACK_HOURS's SC2034 comment says "read only by bin/tick.sh" — it's read by logwatch_timer_lookback_since in the same file.
bin/test-logwatch.sh runs under set -uo pipefail (no -e), so a mistyped/undefined assertion helper would print to stderr and still exit 0. yes is provably defined (CI would hang on coreutils yes); worth a glance that eq and no are too, since both are new usages here.

Test coverage on the pure functions is genuinely good (verdict matrix, lookback direction, cadence parsing, regex precision). What's untested is the wiring in logwatch_review_unit/do_logwatch_tick — the discovery→get_file→subhourly chain in item 2 is exactly the part with no coverage and the part most likely to be silently inert.

_{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 `367e3fee`: **success** Adds timer-awareness to the hourly logwatch pass so a paused `*.timer` explains a silent service journal instead of producing a phantom tick-gap ticket (igor#420). Core logic reads sound and errs conservative (unknown/paused ⇒ skip), CI is green, scope is on-issue, size is within budget. Three things I want a human to weigh before merge — none of them break the #420 fix itself. **1. `logwatch_timer_subhourly` accepts exactly 3600s — that can re-create the false ticket this PR exists to kill (`lib/logwatch.sh`, `secs -le 3600`)** `OnUnitActiveSec=`/`OnUnitInactiveSec=` are measured from the paired service's activation/deactivation, not from a wall clock, so an "hourly" timer's effective period is 3600 + service runtime + up to `AccuracySec` (default 60s) of deferral. Firings drift later, and eventually a clock hour contains zero firings — at which point the new branch turns an empty journal into a "Timer status: silence is itself failure-worthy" prompt and files. `OnCalendar=hourly` (fixed `:00:00`) is safe; the monotonic forms are not. Suggested fix: `-lt 3600` (or a margin like `-le 1800`) for the `OnUnit*Sec` branch only, and flip the `"OnUnitActiveSec=1h -> exactly hourly, still counts"` assertion in `bin/test-logwatch.sh`. **2. The new finding path depends on `forgejo_repo_get_file`, which isn't visible anywhere in this diff (`bin/tick.sh` ~2710)** `timer_file=$(forgejo_repo_get_file "$r_name" "systemd/${base}.timer" 2>/dev/null || true)` — I can't confirm from the diff that (a) the helper exists and (b) it returns *decoded* file contents rather than the Forgejo contents-API base64 blob. Either failure is masked by `|| true` and silently yields `timer_subhourly=0` forever, making the entire "active timer + silent unit ⇒ file" branch dead code with no test or log to reveal it. Please confirm the helper's contract (an existing call site would satisfy me); if it can return base64, decode it. **3. PR description no longer matches the diff** The checklist describes a two-state design built on `logwatch_timer_transitioned`. The diff actually ships five new functions — `logwatch_timer_last_transition`, `logwatch_timer_verdict`, `logwatch_timer_lookback_since`, `logwatch_timespan_secs`, `logwatch_calendar_hourly`, `logwatch_timer_subhourly` — including a general systemd timespan and `OnCalendar` parser, and the "empty journal ⇒ Timer status note" bullet is now additionally gated on `is-active` *and* declared cadence. Nothing checked is fabricated (every box maps to real code), but the description under-describes the change; a human trusting the checklist would not know a calendar-expression parser is in here. Worth updating so the CLAUDE.md text and the description agree. Smaller notes, non-blocking: - `Started|Stopped <unit>` matching assumes systemd ≥ v250, which logs the unit ID; older systemd logs the *Description* instead, so the in-window signal would silently never fire there. The `prior`/`is-active` signals still cover it, so this degrades safely — just noting the test fixtures only cover the new format. - `logwatch_timer_subhourly` treats every `OnCalendar=`/`OnUnit*Sec=` line as additive; systemd resets the list on an empty assignment (`OnCalendar=`), so `OnCalendar=hourly` + `OnCalendar=` + `OnCalendar=daily` would be judged sub-hourly. Obscure, but it's the one direction that produces a false ticket. - `LOGWATCH_TIMER_LOOKBACK_HOURS`'s `SC2034` comment says "read only by bin/tick.sh" — it's read by `logwatch_timer_lookback_since` in the same file. - `bin/test-logwatch.sh` runs under `set -uo pipefail` (no `-e`), so a mistyped/undefined assertion helper would print to stderr and still exit 0. `yes` is provably defined (CI would hang on coreutils `yes`); worth a glance that `eq` and `no` are too, since both are new usages here. Test coverage on the pure functions is genuinely good (verdict matrix, lookback direction, cadence parsing, regex precision). What's untested is the wiring in `logwatch_review_unit`/`do_logwatch_tick` — the discovery→`get_file`→`subhourly` chain in item 2 is exactly the part with no coverage and the part most likely to be silently inert. --- <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-25 03:56:30 +00:00

2 minutes 37 seconds

igor requested review from joshtronic

2026-07-25 03:56:30 +00:00