The logs stop repeating what metrics and their own fields say (#363)

iPX logged scan_done after every scan: 921 lines a day, a fifth of the
log, nearly all "scan complete, 1 feed(s)" since scans became one or two
feeds at a time (#114). ipx_jobs_total, ipx_feed_fetches_total and
ipx_last_scan_age_seconds hold all of it. It is routine now, at debug, so
the page's log view keeps it. The dashboard's "feeds checked" series and
the prod check's check 4 read the metrics instead.

ipx-directory wrote each line's span twice, as `span` and in `spans`, and
neither added anything: a request's span repeated its method, path and
status, refresh.feeds repeated `checked`, a feed span was empty.

ipx::http stays: it repeats Caddy's access line and the span, but holds
the route pattern and ipx's own time, which the dashboard groups by.

The prod check's `status` line was the healthcheck's every 30 s; since
#218 it is only `ipx status` run by hand, and the skill says so.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
2026-10-25 15:01:42 +00:00
parent 1d54f5141d
commit 6352324bcb
6 changed files with 22 additions and 8 deletions

View File

@@ -71,8 +71,8 @@ lines had no trace id, the access log's time was `ms`, and each event was logged
Events (`ev`): `feed_start`, `feed_done` (new, downloaded, failed, torrents), `feed_skip` (not due,
routine), `feed_error` (msg), `feed_moved` (from, to: a permanent redirect followed, the address
updated), `download_done` (bytes), `download_error` (msg, url),
`torrent_deferred`, `reaped`, `scan_done` (feeds checked), `reap_done`, `status` (feeds, pending,
downloaded: the healthcheck's, every 30s), `deadair_done` (feed, enclosure, `saved_s` at the
`torrent_deferred`, `reaped`, `reap_done`, `status` (feeds, pending, downloaded: the answer to
`ipx status`, only when someone runs it since #218), `deadair_done` (feed, enclosure, `saved_s` at the
default pause), `error` (msg). DeadAir also logs `DeadAir found the silences` (`cuts`, `saved_s`,
`took_ms`) under `ipx::deadair`, and warns `DeadAir could not read a file` when ffmpeg fails on
one, which it then passes over until the next restart.
@@ -148,8 +148,8 @@ a count says something happened, the lines and traces say why.
4. **Is the worker keeping up?** Scans should finish regularly, the queue should drain, and the
daemon should not be restarting on its own.
```
$Q metric 'sum(count_over_time({container="iPX"} |= "\"ev\":\"scan_done\"" [$range]))' 6h
$Q logs '{container="iPX"} |= "\"ev\":\"status\"" | json | line_format "{{.timestamp}} pending={{.pending}} downloaded={{.downloaded}}"' 6h
$Q prom 'sum(increase(ipx_jobs_total{job="ipx",kind="scan"}[$range]))' 6h
$Q prom 'max_over_time(ipx_downloads_pending{job="ipx"}[$range])' 6h
$Q logs '{container="iPX"} |= "daemon started"' 7d
```
A `daemon started` not matched by a deploy (see `git log` and the image's build time) is a
@@ -158,8 +158,9 @@ a count says something happened, the lines and traces say why.
keeping up or not running.
Since 2026-10-02 the daemon sleeps until the next feed is due (at most 10 minutes) instead of
scanning every minute (#114), so expect tens of scans in 6 hours, not 360, nearly all with
`feeds` above 0; none at all for over 10 minutes means the worker is stuck. And `pending` is
scanning every minute (#114), so expect a scan every few minutes, most of one or two feeds;
none at all for over 10 minutes means the worker is stuck. A scan's end (`scan_done`) is
logged at debug since #363, so it is in the page's log view and not in Loki. And `pending` is
the real queue (#113): files a scan will download on its own. Back-catalogue files are
`held`, listed but not counted, so it is usually 0 or a handful.
5. **Slow and failed traces.** Look at ipx's requests as spans, not traces: a trace started by a