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>

.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,
+`torrent_deferred`, `reaped`, `reap_done`, `status` (feeds, pending, downloaded: the answer to
-downloaded: the healthcheck's, every 30s), `deadair_done` (feed, enclosure, `saved_s` at the
+`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 prom 'sum(increase(ipx_jobs_total{job="ipx",kind="scan"}[$range]))' 6h
-   $Q logs '{container="iPX"} |= "\"ev\":\"status\"" | json | line_format "{{.timestamp}} pending={{.pending}} downloaded={{.downloaded}}"' 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
+   scanning every minute (#114), so expect a scan every few minutes, most of one or two feeds;
-   `feeds` above 0; none at all for over 10 minutes means the worker is stuck. And `pending` is
+   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

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

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())
         }))

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).

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
         }

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"),