rays/ipx
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases 20 Wiki Activity

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

Browse Source 
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:
Ray Slakinski
2026-10-25 15:01:42 +00:00
parent 1d54f5141d
commit 6352324bcb
6 changed files with 22 additions and 8 deletions
Download Patch File Download Diff File Expand all files Collapse all files

13
.claude/skills/ipx-prod-check/SKILL.md
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

4
crates/directory/CHANGELOG.md
View File

@@ -10,6 +10,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
## [Unreleased]
### Changed
- Its JSON log lines no longer carry their span, once on its own and again in a list, which said nothing the line's own fields did not (#363).
## [1.4.1] - 2026-10-24
### Fixed

3
crates/directory/src/main.rs
View File

@@ -89,6 +89,9 @@ async fn serve(path: &Path) -> Result<()> {
tracing_subscriber::fmt::layer()
.json()
.flatten_event(true)
// Each line's own fields say all its span did, and the list said it again (#363).
.with_current_span(false)
.with_span_list(false)
.with_writer(std::io::stderr)
.with_filter(filter())
}))

4
crates/ipx/CHANGELOG.md
View File

@@ -12,6 +12,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
## [Unreleased]
### Changed
- The log no longer has a line for every scan that finishes, a fifth of its lines; the metrics count scans, and the page's log view still shows them (#363).
### Fixed
- A feed you already have, added again by the same address over http rather than https or the other way round, is the one you have, not a second subscription with every item twice. Changing a feed's address to another feed's over the other scheme is refused the same way (#362).

4
crates/ipx/src/ipc.rs
View File

@@ -307,7 +307,9 @@ fn log_event(e: &Event, wire: bool) {
_ => (None, None),
};
let routine = match e {
Event::Progress { .. } | Event::FeedSkip { .. } | Event::FeedStart { .. } => true,
// A scan's end: ipx_jobs_total, ipx_feed_fetches_total and ipx_last_scan_age_seconds hold it,
// and since scans became one or two feeds at a time it was a fifth of the log (#363).
Event::Progress { .. } | Event::FeedSkip { .. } | Event::FeedStart { .. } | Event::ScanDone { .. } => true,
Event::FeedDone { new, downloaded, failed, torrents, .. } => {
*new == 0 && *downloaded == 0 && *failed == 0 && *torrents == 0
}

2
grafana/dashboard.py
View File

@@ -230,7 +230,7 @@ ts("Waiting", [prom('ipx_worker_queue{job="ipx"}', legend="commands for the work
prom('max(ipx_feed_retries{job="ipx"})', ref="C", legend="feeds to retry a lookup"),
prom('max(ipx_deadair_backlog{job="ipx"})', ref="D", legend="files for DeadAir")],
0, w=8, desc="A queue that only grows means the worker is stuck or behind.")
ts("Feeds checked and new items", [loki(f'sum(sum_over_time({EV} | ev="scan_done" | unwrap feeds [$__interval]))', legend="feeds checked"),
ts("Feeds checked and new items", [prom('sum(increase(ipx_feed_fetches_total{job="ipx"}[$__interval]))', legend="feeds checked"),
loki(f'sum(sum_over_time({EV} | ev="feed_done" | unwrap new [$__interval]))', ref="B", legend="new items")],
8, w=8, bars=True, desc="Feeds that were due and fetched; the rest were skipped as not due.")
ts("Downloads", [loki(f'sum(count_over_time({EV} | ev="download_done" [$__interval]))', legend="saved"),