diff --git a/.claude/skills/ipx-prod-check/SKILL.md b/.claude/skills/ipx-prod-check/SKILL.md index f6ce5aa..1923b36 100644 --- a/.claude/skills/ipx-prod-check/SKILL.md +++ b/.claude/skills/ipx-prod-check/SKILL.md @@ -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 diff --git a/crates/directory/CHANGELOG.md b/crates/directory/CHANGELOG.md index 905e088..3825bec 100644 --- a/crates/directory/CHANGELOG.md +++ b/crates/directory/CHANGELOG.md @@ -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 diff --git a/crates/directory/src/main.rs b/crates/directory/src/main.rs index 07668c0..93bdc41 100644 --- a/crates/directory/src/main.rs +++ b/crates/directory/src/main.rs @@ -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()) })) diff --git a/crates/ipx/CHANGELOG.md b/crates/ipx/CHANGELOG.md index a8c18ea..b95d059 100644 --- a/crates/ipx/CHANGELOG.md +++ b/crates/ipx/CHANGELOG.md @@ -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). diff --git a/crates/ipx/src/ipc.rs b/crates/ipx/src/ipc.rs index cd85fcf..ec62a96 100644 --- a/crates/ipx/src/ipc.rs +++ b/crates/ipx/src/ipc.rs @@ -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 } diff --git a/grafana/dashboard.py b/grafana/dashboard.py index b03a847..1a1deef 100644 --- a/grafana/dashboard.py +++ b/grafana/dashboard.py @@ -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"),